device/telemetry: keep probing when the epoch fetch fails - #4143

The 12h bound outlives the buffer, and the overflow silently backdates every later sample in the account.

partitionBufferCapacity = 4096 per partition (collector.go:17); at the default -probe-interval=10s that is 11.4h of samples for one link — inside this 12h window. During a ledger outage the submitter cannot drain either, so each 60s tick does CopyAndReset, fails all 5 attempts, and prepends the batch back only while Len + len(tmp) < Capacity. The first time that check trips at ~11.4h (submitter.go:248), the entire accumulated backlog is discarded in one tick rather than the oldest slice, and accumulation restarts from zero. A 12h outage therefore yields roughly 36 minutes of samples on recovery, not 12h.

What makes this High rather than a tuning nit is what the discard does to the data that does survive. The onchain account stores one start_timestamp_microseconds, one sampling_interval_microseconds, and a flat samples array with no per-sample timestamps (smartcontract/programs/doublezero-telemetry/src/state/device_latency_samples.rs:117-123), and the reader synthesizes each timestamp as start + i*interval (controlplane/telemetry/internal/data/device/latencies.go:205). A dropped run leaves no marker, so every sample appended after the discard is backdated by the full 11.4h gap. Wrong data presented as good data is worse than the probe gap this PR removes.

This state was not reachable before the change: the pre-fix pinger stopped adding during an outage, so the partition never grew and the over-capacity path never tripped.

Fix (one line for the immediate hazard): set DefaultMaxEpochStaleness below the buffer's real retention — derive it as partitionBufferCapacity × ProbeInterval, or hardcode a value with margin (8h) rather than one past the cliff. The comment above should also name the real binding constraint; rollover likelihood is not it, given a ~44h ledger epoch and no onchain epoch check. Worth a follow-up: have the over-capacity path keep the newest Capacity - Len samples instead of dropping all of tmp.

Test: a submitter-level test with a small partitionBufferCapacity and a failing WriteDeviceLatencySamples, asserting the observed sample rate stays within tolerance of ProbeInterval across the whole allowed staleness window.

Fixed, in both halves.

The default is now 10h rather than 11h, and the collector clamps whatever is configured to partitionBufferCapacity × ProbeInterval × 0.95 (collector.go, maxEpochStaleness). 10h so the default does not itself trip the clamp warning at the default probe interval — 11h is inside the 11.4h cliff but past the 10.8h the headroom leaves, and a warning on every healthy startup is noise. The clamp is what keeps a non-default -probe-interval safe: at 5s the buffer only holds 5.7h, and a flat 10h would be past the cliff again.

The comment above the constant now names the buffer as the binding constraint, and says what the overflow does to the data rather than talking about rollover likelihood — the rollover is bounded separately now, see below.

Tests: TestMaxEpochStaleness covers the clamp arithmetic and asserts the default does not need clamping. TestSubmitter_RetainsEverySampleAcrossTheStalenessBound is the submitter-level one you asked for — small capacity, WriteDeviceLatencySamples refusing every write, probing for the full window the bound allows, then asserting every sample survives the flush once writes recover. It also require.Less(probes, capacity) up front, so if the bound ever drifts back past the buffer the test fails on the premise rather than the assertion. Verified both fail with the clamp no-oped and the default back at 12h.

The over-capacity path keeping the newest Capacity - Len instead of dropping all of tmp is filed as #4149.

The inline fetch makes epochForTick a second concurrent writer to the epoch cache, and each act-on-stale-read is observable.

haveEpoch is read under the lock at lines 205-207, then this fetch runs for tens of seconds when failing. Three consequences follow from acting on that stale read, and from emitting side effects outside the critical section that flipped the corresponding flag:

1. If the concurrent refreshEpochLoop lands an epoch during the retry window, the failure branch below still fires — it increments errors_total{pinger_epoch_unavailable} and logs Error("No epoch available and none cached, skipping probes until the ledger answers") while a fresh epoch sits in the cache. An operator-facing ERROR and an error-counter increment on a healthy agent is a false page source, in exactly the flapping/partially-degraded-RPC scenario this PR targets.
2. markEpochStale sets servingStale under the lock at 316-317 but logs at 330. A storeEpoch from this inline path can run in the gap and log "Epoch fetch recovered" (302) before the failure it recovered from, with staleFor ≈ 0.
3. markEpochStale reads at under the lock at 315 but calls EpochCacheStaleAge.Set(age) outside it at 327, racing storeEpoch's Set(0) at 298. The gauge can be left large right after a successful fetch. It self-heals in one refresh interval, but this gauge is the operator's only staleness signal.

Fix: make refreshEpochLoop the sole writer and have epochForTick read the cache only. The cost is one skipped tick at startup, and Tick-without-Run no longer self-seeds, which affects the subtest at pinger_test.go:440. If the inline fetch stays, re-read the cache under mu after it fails and fall through to the staleness check at line 232 when an epoch landed meanwhile, and move each log and Set inside the critical section that flips its flag.

Test: a -race test driving Tick concurrently with Run while the fetch flaps, asserting no ERROR is emitted while an epoch is cached, and that the gauge is 0 whenever the last fetch succeeded.

Fixed the way you suggested: RefreshEpoch is the sole writer and epochForTick only reads the cache and decides. The inline fetch is gone, so all three consequences go with it — no ERROR or error-counter increment while a fresh epoch is cached, no recovery logged before the failure it recovered from, no gauge left large after a success. Every log line and every Set now happens inside the critical section that flips its flag.

On the cost you flagged: refreshEpochLoop refreshes immediately on start and the first probe tick is Interval later, so a healthy agent skips nothing. Tick-without-Run no longer self-seeds, so the three affected subtests now call RefreshEpoch explicitly — which reads better anyway, since the seeding is now visible instead of a side effect of the first tick. refreshEpoch is exported as RefreshEpoch for that, mirroring how Tick exposes one step of the probe loop.

Test: TestAgentTelemetry_PingerEpochMetrics/a_flapping_fetch_never_reports_an_error_while_an_epoch_is_cached drives Tick in a loop against a running Run with the fetch flapping, under -race, and asserts no ERROR is emitted and pinger_epoch_never_fetched does not move. It then settles the flapping on a success and asserts the gauge is 0.

markEpochStale returns here before setting EpochCacheStaleAge, so the gauge reads 0 in the worst state — restarted mid-outage, no epoch ever fetched, zero probing — exactly as it does when healthy. Emit a sentinel on this branch, and add the one subtest that would have caught it (testutil.ToFloat64 asserting the gauge tracks age while stale and returns to 0 on recovery). Neither new metric has any coverage today.

Fixed. That branch now sets the gauge to +Inf, so an alert on stale_age > threshold fires in the state where nothing is being probed at all, rather than reading identically to healthy. +Inf rather than -1 for exactly that reason — a negative sentinel would pass the same alert silently. Noted in the metric's Help string.

Both new metrics now have coverage: TestAgentTelemetry_PingerEpochMetrics has one subtest walking the gauge through fresh → stale → staler → recovered with testutil.ToFloat64, one asserting the +Inf sentinel, and one asserting each refusal and each failed attempt lands on its own counter. Verified the sentinel subtest fails with the Set removed.

"No epoch ever fetched" (boot ordering, bad ledger URL, line 214) and "gave up after MaxEpochStaleness" (outage, here) share one errors_total value, which is what the fleet alert fires on. Split into two error types while the type is being introduced.

Split, into three rather than two. pinger_epoch_never_fetched for boot ordering or a bad ledger URL, pinger_epoch_too_stale for giving up after the bound, and pinger_epoch_ended for the new projected-rollover refusal. Covered by each_refusal_and_each_failed_attempt_is_counted_separately, which asserts each one moves on its own trigger and not on the others.

The demotion itself is right, but the fetch-failure signal now has no coverage in one direction and no debounce in the other. When retries eventually succeed (the partial-outage mode) markEpochStale never runs, so there is no signal above Debug and no metric at all. When the RPC flaps at the 10s refresh, each flap emits a Warn (330) plus an Info (302) — against this PR's own single-digit-log-lines goal. Add a per-failed-attempt counter here, and require N consecutive failures before the Warn.

Both fixed.

Coverage in the eventually-succeeds direction: pinger_epoch_fetch_failed now increments per failed attempt inside getEpochInfo, so a partially degraded endpoint whose retries ride it out still leaves a signal even though markEpochStale never runs. Kept at Debug for the log line itself, for the reason in the original comment.

Debounce in the other: the fresh→stale Warn now waits for epochStaleWarnAfter (3) consecutive failed fetches, and the recovery Info is gated on whether that Warn actually fired — so a flap produces neither, rather than one of each. storeEpoch resets the counter.

Test: does_not_report_a_fallback_the_retries_recovered_from runs two flaps and asserts nothing above Debug, then a sustained outage and asserts exactly one Warn on the third consecutive failure and one Info on recovery. Verified it fails with the debounce removed.

time.Now().UTC() strips the monotonic reading, so NowFunc().Sub(at) is pure wall-clock arithmetic. A device booting with a bad RTC and then NTP-stepping forward trips the staleness bound instantly and stops probing until the next successful fetch. Keep a monotonic timestamp alongside epochAt and measure age from it.

Fixed. NowFunc defaults to time.Now rather than time.Now().UTC(), so the reading carries monotonic and NowFunc().Sub(at) is monotonic arithmetic; the .UTC() moved to the log call sites where it belongs. A bad RTC stepping forward over NTP no longer looks like hours of staleness.

The collector deliberately no longer passes Config.NowFunc into PingerConfig — that one is the UTC wall clock the sender cache uses for its bookkeeping, and it strips exactly the reading this needs. Comment at the call site says so, so it does not get helpfully wired back.

Injected test clocks are wall-only, which Sub handles by falling back to wall-clock arithmetic; that is what the staleness and rollover subtests rely on.

EpochRefreshInterval is a new config field with no CLI flag and no non-test caller, and its defaultEpochRefreshInterval fallback (lines 24-25, 75-77) is unreachable: Config.Validate rejects ProbeInterval <= 0 (config.go:96) and Run would panic in time.NewTicker(0) first. Either wire a flag next to -max-epoch-staleness — the epoch resolves once per ~44h, so refreshing every 10s is ~8.6k RPC calls/day/device that an operator now cannot turn down — or drop the field and the constant and read Interval directly.

Wired a flag: -epoch-refresh-interval, next to -max-epoch-staleness. It defaults to 0, which follows -probe-interval, so the epoch RPC rate is unchanged from before this PR and stays coupled if an operator changes the probe interval — and the ~8.6k calls/day/device can now be turned down without touching the probe cadence.

The unreachable defaultEpochRefreshInterval fallback stays, but it is no longer dead: PingerConfig is constructed directly by tests with no Interval set, and NewPinger would otherwise hand time.NewTicker a zero. Config.Validate still rejects ProbeInterval <= 0 for the collector path.

-max-epoch-staleness=0 silently becomes 12h, the opposite of the natural reading of the flag's "before giving up". main.go:117 already fails fast on probe-interval >= submission-interval; reject <= 0 there too rather than defaulting silently past an operator's intent.

Fixed in main.go, next to the probe-interval >= submission-interval check:

if *maxEpochStaleness <= 0 {
    fmt.Println("max-epoch-staleness must be greater than 0")
    os.Exit(1)
}

Plus the same for a negative -epoch-refresh-interval, since 0 there means "follow -probe-interval" and is deliberate.

The zero-value default in Config.Validate stays. It is a library default for embedded callers who never see a flag, and the flag path can no longer reach it.